fix: MDC 복사가 종료 신호를 건너뛰어 다음 시퀀스가 이전 Context 로 로그를 남기는 문제 수정 - #372

수정 사유 Reason for modification

• 버그수정 Bug fixes
• 기능개선 Enhancements
• 기능추가 Adding features
• 기타 Others

수정된 소스 내용 Modified source

EgovMdcContextConfig.EgovSubscriber 는 onNext 에서만 copyToMdc(coreSubscriber.currentContext()) 를 부릅니다. 종료 신호인 onError 와 onComplete 는 그대로 위임합니다.

// EgovMdcContextConfig.java:106
public void onNext(T t) {
    copyToMdc(coreSubscriber.currentContext());
    coreSubscriber.onNext(t);
}

// EgovMdcContextConfig.java:112
public void onError(Throwable throwable) {
    coreSubscriber.onError(throwable);
}

"MDC 는 현재 Context 와 일치해야 한다" 는 규칙은 이 클래스가 스스로 세운 것입니다. copyToMdc 는 Context 가 비어 있으면 MDC.clear() 까지 합니다. 클래스 Javadoc 도 "스레드의 변경이 있을 때마다 Context의 값을 MDC에 삽입" 이라고만 적어 신호 종류를 가리지 않습니다.

@PostConstruct contextOperatorHook() 이 Hooks.onEachOperator 로 전역 등록하므로 이 빈이 뜬 뒤 만들어지는 모든 Mono/Flux 가 EgovSubscriber 로 감싸집니다.

Reactor 스케줄러 스레드는 재사용됩니다. publishOn 으로 하류가 다른 스레드로 넘어가면 상류 절반이 돌던 스레드에는 그 시퀀스의 Context 값이 MDC 에 남습니다. 같은 스레드에서 다음 시퀀스가 값 없이 완료되거나 에러로 끝나면 onNext 가 한 번도 불리지 않아, 자기 Context 를 두고도 종료 콜백(doOnTerminate·doFinally·에러 핸들러)의 로그가 앞 시퀀스의 값으로 찍힙니다. WebFilter 로 traceId·userId 를 Context 에 넣는 구성이라면 다른 요청의 식별자가 로그에 섞입니다.

AS-IS / TO-BE

onNext 와 같은 자리에서 두 종료 신호도 copyToMdc 를 거치게 했습니다.

     @Override
     public void onError(Throwable throwable) {
+        copyToMdc(coreSubscriber.currentContext());
         coreSubscriber.onError(throwable);
     }
 
     @Override
     public void onComplete() {
+        copyToMdc(coreSubscriber.currentContext());
         coreSubscriber.onComplete();
     }

영향 범위

값이 흐르는 시퀀스의 MDC 최종 상태는 그대로입니다. 마지막 onNext 와 같은 Context 를 한 번 더 쓰기 때문입니다. 종료 신호는 시퀀스당 한 번이라 늘어나는 호출도 시퀀스당 한 번입니다.

같은 이너클래스의 onSubscribe(:101)도 copyToMdc 를 거치지 않아 doOnSubscribe 콜백은 여전히 앞 시퀀스의 값을 볼 수 있습니다. 구독 신호는 호출 스레드의 MDC 까지 덮게 되는 범위라 판단이 갈려 이번에는 종료 신호만 맞췄습니다.

시퀀스가 끝난 뒤 스레드에 MDC 가 남는 것 자체는 이 수정으로 달라지지 않습니다. 그 자리의 Context 는 실제로 그 값이라 이 클래스의 규칙에 어긋나지 않고, 언제나 지우려면 다른 설계가 필요해 이 PR 범위 밖으로 두었습니다.

JUnit 테스트 JUnit tests

• JUnit 테스트 JUnit tests
• 수동 테스트 Manual testing

EgovMdcContextConfigTest 2건을 더했습니다. 공개 진입점인 contextOperatorHook()·cleanupHook() 만 쓰고, newSingle 스케줄러 두 개로 상·하류를 갈라 스레드 재사용을 결정론적으로 만듭니다. 두 번째 시퀀스의 Context 는 userId=B 인데 종료 콜백이 읽은 MDC 는 userId=A 입니다.

수정 두 줄을 도로 빼면 실패합니다.

$ mvn -o test -pl Foundation/org.egovframe.rte.fdl.reactive -Dtest=EgovMdcContextConfigTest
[ERROR]   EgovMdcContextConfigTest.completionOfNextSequenceSeesItsOwnContext:61 expected: <B> but was: <A>
[ERROR]   EgovMdcContextConfigTest.errorOfNextSequenceSeesItsOwnContext:82 expected: <B> but was: <A>
[ERROR] Tests run: 2, Failures: 2, Errors: 0, Skipped: 0
[INFO] BUILD FAILURE

수정 후 모듈 전체입니다.

$ mvn -o test -pl Foundation/org.egovframe.rte.fdl.reactive
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0
[INFO] BUILD SUCCESS

테스트 브라우저 Test Browser

• Chrome
• Firefox
• Edge
• Safari
• Opera
• Internet Explorer
• 기타 Others

테스트 스크린샷 또는 캡처 영상 Test screenshots or captured video

화면이 없는 실행환경 모듈이라 첨부하지 않았습니다.